/*
*----------------------------------------------------------------------
*
* edg_wll_log_proto_server - handle incoming data
*
* Returns: 0 if done properly or errno
*
* Calls:
*
* Algorithm:
*
*----------------------------------------------------------------------
*/
int edg_wll_log_proto_server(edg_wll_GssConnection *con, struct timeval *timeout, char *name, char *prefix, int noipc, int noparse)
{
char *buf,*dglllid,*dguser,*jobId,*name_esc;
char header[EDG_WLL_LOG_SOCKET_HEADER_LENGTH+1];
char outfilename[FILENAME_MAX];
size_t count;
int count_total,size;
u_int8_t size_end[4];
size_t msg_size,dglllid_size,dguser_size;
int i,answer,answer_sent;
int msg_sock;
char *msg,*msg_begin;
int filedesc,filelock_status;
long filepos;
int priority;
long lllid;
int unique;
int err;
edg_wll_Context context;
edg_wll_Event *event;
edg_wlc_JobId j;
edg_wll_GssStatus gss_stat;
errno = i = answer = answer_sent = size = msg_size = dglllid_size = dguser_size = count = count_total = msg_sock = filedesc = filelock_status = /* priority */ unique = err = 0;
buf = dglllid = dguser = jobId = name_esc = msg = msg_begin = NULL;
event = NULL;
/* init */
if (edg_wll_InitContext(&context) != 0) {
glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_ERROR,"edg_wll_InitContex(): error.\n");
answer = ENOMEM;
goto edg_wll_log_proto_server_end;
}
if (edg_wll_ResetError(context) != 0) {
glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_ERROR,"edg_wll_ResetError(): error.\n");
answer = ENOMEM;
goto edg_wll_log_proto_server_end;
}
/* look for the unique unused long local-logger id (LLLID) */
lllid = 1000*getpid();
for (i=0; (i<1000)&&(!unique); i++) {
struct stat statbuf;
lllid += i;
snprintf(confirm_sock_name, sizeof(confirm_sock_name), "/tmp/dglogd_sock_%ld", lllid);
if ((filedesc = stat(confirm_sock_name,&statbuf)) == 0) {
glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_WARN,"Warning: LLLID %ld already in use.\n",lllid);
} else {
if (errno == ENOENT) {
unique = 1;
} else {
glite_common_log_SYS_ERROR("stat");
}
}
}
if (!unique) {
glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_ERROR,"Cannot determine the unique long local-logger id (LLLID %ld)!\n",lllid);
return EAGAIN;
}
glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_INFO,"Long local-logger id (LLLID): %ld ... [ok]\n",lllid);
/* receive socket header */
memset(header, 0, EDG_WLL_LOG_SOCKET_HEADER_LENGTH+1);
if ((err = edg_wll_gss_read_full(con, header, EDG_WLL_LOG_SOCKET_HEADER_LENGTH, timeout, &count, &gss_stat)) < 0) {
if (err == EDG_WLL_GSS_ERROR_EOF) {
glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_WARN,"Reading socket header - no data available.\n");
answer = err;
answer_sent = 1; /* i.e. do not try to send answer back */
} else {
glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_WARN,"Error reading socket header.\n");
answer = handle_gss_failures(err,&gss_stat,"Error reading socket header");
}
goto edg_wll_log_proto_server_end;
} else {
glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_DEBUG,"Reading socket header... [ok]\n");
}
/* Check socket header */
header[EDG_WLL_LOG_SOCKET_HEADER_LENGTH] = '\0';
if (strncmp(header,EDG_WLL_LOG_SOCKET_HEADER,EDG_WLL_LOG_SOCKET_HEADER_LENGTH)) {
/* not the proper socket header text */
glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_WARN,"edg_wll_log_proto_server(): invalid socket header\n");
glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_DEBUG,"edg_wll_log_proto_server(): read header '%s' instead of '%s'\n",
header,EDG_WLL_LOG_SOCKET_HEADER);
answer = EINVAL;
goto edg_wll_log_proto_server_end;
} else {
glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_DEBUG,"Read socket header: \"%s\" [ok]\n",header);
}
/* XXX: obsolete
count = 0;
if ((err = edg_wll_gss_read_full(con, &priority, sizeof(priority), timeout, &count, &gss_stat)) < 0) {
glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_WARN,"Error reading message priority.\n");
answer = handle_gss_failures(err,&gss_stat,"Error receiving message priority");
goto edg_wll_log_proto_server_end;
} else {
glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_DEBUG,"Read message priority: %d [ok]\n",priority);
}
*/
/* read message size */
count = 0;
if ((err = edg_wll_gss_read_full(con, size_end, 4, timeout, &count,&gss_stat)) < 0) {
glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_DEBUG,"Error reading message size.\n");
answer = handle_gss_failures(err,&gss_stat,"Error reading message size");
goto edg_wll_log_proto_server_end;
} else {
glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_DEBUG,"Reading message size... [ok]\n");
}
size = size_end[3]; size <<=8;
size |= size_end[2]; size <<=8;
size |= size_end[1]; size <<=8;
size |= size_end[0];
if (size <= 0) {
/* probably wrong size in the header or nothing to read */
glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_WARN,"edg_wll_log_proto_server(): invalid size read from socket header\n");
glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_DEBUG,"Read message size '%d' [error].\n",size);
answer = EINVAL;
goto edg_wll_log_proto_server_end;
} else {
glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_DEBUG,"Read message size: %d bytes [ok].\n",size);
}
/* format the DG.LLLID string */
if (asprintf(&dglllid,"DG.LLLID=%ld ",lllid) == -1) {
glite_common_log_SYS_ERROR("asprintf");
glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_WARN,"edg_wll_log_proto_server(): nomem for DG.LLLID\n");
answer = ENOMEM;
goto edg_wll_log_proto_server_end;
}
dglllid_size = strlen(dglllid);
/* format the DG.USER string */
name_esc = glite_lbu_EscapeULM(name);
if (asprintf(&dguser,"DG.USER=\"%s\" ",name_esc) == -1) {
glite_common_log_SYS_ERROR("asprintf");
glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_WARN,"edg_wll_log_proto_server(): nomem for DG.USER\n");
answer = ENOMEM;
goto edg_wll_log_proto_server_end;
}
dguser_size = strlen(dguser);
/* allocate enough memory for all data */
msg_size = dglllid_size + dguser_size + size + 1;
if ((msg = malloc(msg_size)) == NULL) {
glite_common_log_SYS_ERROR("malloc");
glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_WARN,"edg_wll_log_proto_server(): out of memory for allocating message\n");
answer = ENOMEM;
goto edg_wll_log_proto_server_end;
}
strncpy(msg,dglllid,dglllid_size);
msg_begin = msg + dglllid_size; // this is the "official" beginning of the message
strncpy(msg_begin,dguser,dguser_size);
/* receive message */
buf = msg_begin + dguser_size;
count = 0;
if ((err = edg_wll_gss_read_full(con, buf, size, timeout, &count, &gss_stat)) < 0) {
glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_WARN,"Error reading message from socket.\n");
answer = handle_gss_failures(err,&gss_stat,"Error reading message from socket.");
goto edg_wll_log_proto_server_end;
} else {
glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_DEBUG,"Reading message... [ok]\n");
// glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_TRACE,"Read message: \"%s\"\n",msg);
}
buf[count] = '\0';
/* parse message and get jobId and priority from it */
if (!noparse && strstr(msg, "DG.TYPE=\"command\"") == NULL) {
if (edg_wll_ParseEvent(context,msg_begin,&event) != 0) {
glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_WARN,"edg_wll_log_proto_server(): edg_wll_ParseEvent error\n");
glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_WARN,"edg_wll_ParseEvent(): %s\n",context->errDesc);
answer = edg_wll_Error(context,NULL,NULL);
goto edg_wll_log_proto_server_end;
} else {
glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_DEBUG,"Parsing message for correctness...[ok]\n");
}
jobId = edg_wlc_JobIdGetUnique(event->any.jobId);
priority = event->any.priority;
edg_wll_FreeEvent(event);
event->any.priority = priority;
glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_DEBUG,"Getting jobId from message...[ok]\n");
} else {
if ((event = edg_wll_InitEvent(EDG_WLL_EVENT_UNDEF)) == NULL) {
glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_WARN, "edg_wll_InitEvent(): out of memory\n");
answer = ENOMEM;
goto edg_wll_log_proto_server_end;
}
jobId = edg_wll_GetJobId(msg);
if (!jobId || edg_wlc_JobIdParse(jobId,&j)) {
glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_WARN,"Error getting jobId from message.\n");
glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_WARN,"edg_wlc_JobIdParse(%s)\n",jobId?jobId:"NULL");
answer = EINVAL;
goto edg_wll_log_proto_server_end;
} else {
glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_DEBUG,"Getting jobId from message...[ok]\n");
}
free(jobId);
jobId = edg_wlc_JobIdGetUnique(j);
edg_wlc_JobIdFree(j);
/* TODO: get the priority from message some better way */
if (strstr(msg, "DG.PRIORITY=1") != NULL)
event->any.priority = 1;
else event->any.priority = 0;
}
if (event->any.priority & (EDG_WLL_LOGFLAG_SYNC|EDG_WLL_LOGFLAG_SYNC_COMPAT)) {
if(init_confirmation() < 0) {
glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_WARN,"Error initializing 2nd UNIX socket (%s) for priority messages confirmation.\n",confirm_sock_name);
answer = errno;
goto edg_wll_log_proto_server_end;
} else {
glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_DEBUG,"Initializing 2nd UNIX socket (%s) for priority messages confirmation...[ok]\n",confirm_sock_name);
}
}
/* if not command, save message to file */
if(strstr(msg, "DG.TYPE=\"command\"") == NULL) {
/* compose the name of the log file */
count = strlen(prefix);
strncpy(outfilename,prefix,count); count_total=count;
strncpy(outfilename+count_total,".",1); count_total+=1; count=strlen(jobId);
strncpy(outfilename+count_total,jobId,count); count_total+=count;
outfilename[count_total]='\0';
// glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_DEBUG,"Composing filename from prefix \"%s\" and unique jobId \"%s\"...[ok]",prefix,jobId);
/* fopen and properly handle the filelock */
#ifdef LOGD_NOFILE
glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_INFO,"NOT writing message to \"%s\".\n",outfilename);
filepos = 0;
#else
if ( edg_wll_log_event_write(context, outfilename, msg, FCNTL_ATTEMPTS, FCNTL_TIMEOUT, &filepos) ) {
char *errd;
// FIXME: there is probably not a correct errno
glite_common_log_SYS_ERROR("edg_wll_log_event_write");
answer = edg_wll_Error(context, NULL, &errd);
glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_WARN,"edg_wll_log_event_write error: %s\n",errd);
free(errd);
goto edg_wll_log_proto_server_end;
} else glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_INFO,"Writing message to \"%s\"... [ok]",outfilename);
#endif
} else {
filepos = 0;
}
#ifdef LB_PERF
glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_INFO,"Calling perftest\n");
glite_wll_perftest_consumeEventString(msg);
glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_INFO,"Calling perftest... [done]\n");
#endif
/* if not priority send now the answer back to client */
if (!(event->any.priority & (EDG_WLL_LOGFLAG_SYNC|EDG_WLL_LOGFLAG_SYNC_COMPAT))) {
if (!send_answer_back(con,answer,timeout)) {
answer_sent = 1;
}
}
/* send message via IPC (UNIX socket) */
if (!noipc) {
if ( edg_wll_log_event_send(context, socket_path, filepos, msg, msg_size, CONNECT_ATTEMPTS, timeout) ) {
char *errd;
// XXX: probably not a SYSTEM ERROR
// glite_common_log_SYS_ERROR("edg_wll_log_event_send");
answer = edg_wll_Error(context, NULL, &errd);
glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_WARN,"edg_wll_log_event_send error: %s\n",errd);
free(errd);
goto edg_wll_log_proto_server_end_1;
} else glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_DEBUG,
"Sending via IPC (UNIX socket \"%s\")\n\t"
"the message position %ld (%ld bytes)... [ok]",
socket_path, filepos, sizeof(filepos));
} else {
glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_DEBUG,"NOT sending via IPC.\n");
}
if (event->any.priority & (EDG_WLL_LOGFLAG_SYNC|EDG_WLL_LOGFLAG_SYNC_COMPAT)) {
if ((count = wait_for_confirmation(timeout, &answer)) < 0) {
glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_WARN,"Error waiting for confirmation.\n");
answer = errno;
} else {
glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_DEBUG,"Waiting for confirmation... [ok].\n");
if (count == 0) {
glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_DEBUG,"Waking up, timeout expired.\n");
answer = EAGAIN;
} else {
glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_DEBUG,"Confirmation received, waking up.\n");
}
}
}
edg_wll_log_proto_server_end:
/* if not sent already, send the answer back to client */
if (!answer_sent) {
answer = send_answer_back(con,answer,timeout);
}
/* clean */
edg_wll_FreeContext(context);
if (name_esc) free(name_esc);
if (dglllid) free(dglllid);
if (dguser) free(dguser);
if (jobId) free(jobId);
if (msg) free(msg);
if (event) free(event);
// glite_common_log(LOG_CATEGORY_ACCESS,LOG_PRIORITY_INFO,"Done.\n");
return answer;
edg_wll_log_proto_server_end_1:
if (event->any.priority) {
close(confirm_sock);
unlink(confirm_sock_name);
}
goto edg_wll_log_proto_server_end;
}
/**
* M600: Pause for filament change
*
* E[distance] - Retract the filament this far
* Z[distance] - Move the Z axis by this distance
* X[position] - Move to this X position, with Y
* Y[position] - Move to this Y position, with X
* U[distance] - Retract distance for removal (manual reload)
* L[distance] - Extrude distance for insertion (manual reload)
* B[count] - Number of times to beep, -1 for indefinite (if equipped with a buzzer)
* T[toolhead] - Select extruder for filament change
*
* Default values are used for omitted arguments.
*/
void GcodeSuite::M600() {
point_t park_point = NOZZLE_PARK_POINT;
const int8_t target_extruder = get_target_extruder_from_command();
if (target_extruder < 0) return;
#if ENABLED(DUAL_X_CARRIAGE)
int8_t DXC_ext = target_extruder;
if (!parser.seen('T')) { // If no tool index is specified, M600 was (probably) sent in response to filament runout.
// In this case, for duplicating modes set DXC_ext to the extruder that ran out.
#if ENABLED(FILAMENT_RUNOUT_SENSOR) && NUM_RUNOUT_SENSORS > 1
if (dxc_is_duplicating())
DXC_ext = (READ(FIL_RUNOUT2_PIN) == FIL_RUNOUT_INVERTING) ? 1 : 0;
#else
DXC_ext = active_extruder;
#endif
}
#endif
// Show initial "wait for start" message
#if HAS_LCD_MENU && DISABLED(PRUSA_MMU2)
lcd_advanced_pause_show_message(ADVANCED_PAUSE_MESSAGE_INIT, ADVANCED_PAUSE_MODE_PAUSE_PRINT, target_extruder);
#endif
#if ENABLED(HOME_BEFORE_FILAMENT_CHANGE)
// Don't allow filament change without homing first
if (axis_unhomed_error()) gcode.home_all_axes();
#endif
#if EXTRUDERS > 1
// Change toolhead if specified
const uint8_t active_extruder_before_filament_change = active_extruder;
if (
active_extruder != target_extruder
#if ENABLED(DUAL_X_CARRIAGE)
&& dual_x_carriage_mode != DXC_DUPLICATION_MODE && dual_x_carriage_mode != DXC_SCALED_DUPLICATION_MODE
#endif
) tool_change(target_extruder, 0, false);
#endif
// Initial retract before move to filament change position
const float retract = -ABS(parser.seen('E') ? parser.value_axis_units(E_AXIS) : 0
#ifdef PAUSE_PARK_RETRACT_LENGTH
+ (PAUSE_PARK_RETRACT_LENGTH)
#endif
);
// Lift Z axis
if (parser.seenval('Z')) park_point.z = parser.linearval('Z');
// Move XY axes to filament change position or given position
if (parser.seenval('X')) park_point.x = parser.linearval('X');
if (parser.seenval('Y')) park_point.y = parser.linearval('Y');
#if HAS_HOTEND_OFFSET && DISABLED(DUAL_X_CARRIAGE) && DISABLED(DELTA)
park_point.x += (active_extruder ? hotend_offset[X_AXIS][active_extruder] : 0);
park_point.y += (active_extruder ? hotend_offset[Y_AXIS][active_extruder] : 0);
#endif
#if ENABLED(PRUSA_MMU2)
// For MMU2 reset retract and load/unload values so they don't mess with MMU filament handling
constexpr float unload_length = 0.5f,
slow_load_length = 0.0f,
fast_load_length = 0.0f;
#else
// Unload filament
const float unload_length = -ABS(parser.seen('U') ? parser.value_axis_units(E_AXIS)
: fc_settings[active_extruder].unload_length);
// Slow load filament
constexpr float slow_load_length = FILAMENT_CHANGE_SLOW_LOAD_LENGTH;
// Fast load filament
const float fast_load_length = ABS(parser.seen('L') ? parser.value_axis_units(E_AXIS)
: fc_settings[active_extruder].load_length);
#endif
const int beep_count = parser.intval('B',
#ifdef FILAMENT_CHANGE_ALERT_BEEPS
FILAMENT_CHANGE_ALERT_BEEPS
#else
-1
#endif
);
if (pause_print(retract, park_point, unload_length, true DXC_PASS)) {
#if ENABLED(PRUSA_MMU2)
mmu2_M600();
resume_print(slow_load_length, fast_load_length, 0, beep_count DXC_PASS);
#else
wait_for_confirmation(true, beep_count DXC_PASS);
resume_print(slow_load_length, fast_load_length, ADVANCED_PAUSE_PURGE_LENGTH, beep_count DXC_PASS);
#endif
}
#if EXTRUDERS > 1
// Restore toolhead if it was changed
if (active_extruder_before_filament_change != active_extruder)
tool_change(active_extruder_before_filament_change, 0, false);
#endif
}