$NetBSD: patch-ac,v 1.2 2006/03/14 13:53:57 rillig Exp $ Added more logging and made its appearance more consistent. --- pptp_ctrl.c.orig 2005-07-28 03:15:11.000000000 +0200 +++ pptp_ctrl.c 2006-03-14 14:26:42.000000000 +0100 @@ -291,6 +291,7 @@ PPTP_CONN * pptp_conn_open(int inet_sock hton16(PPTP_MAX_CHANNELS), hton16(PPTP_FIRMWARE_VERSION), PPTP_HOSTNAME, PPTP_VENDOR }; + log("sending start ctrl conn rqst"); /* fix this packet, if necessary */ int idx, rc; idx = get_quirk_index(); @@ -366,6 +367,7 @@ PPTP_CALL * pptp_call_open(PPTP_CONN * c packet.phone_len = sizeof(packet.phone_num); packet.phone_len = hton16 (packet.phone_len); } + log("sending out call rqst"); if (pptp_send_ctrl_packet(conn, &packet, sizeof(packet))) { pptp_reset_timer(); call->state.pns = PNS_WAIT_REPLY; @@ -393,6 +395,7 @@ void pptp_call_close(PPTP_CONN * conn, P /* don't check state against WAIT_DISCONNECT... allow multiple disconnect * requests to be made. */ + log("sending call clear rqst"); pptp_send_ctrl_packet(conn, &rqst, sizeof(rqst)); pptp_reset_timer(); call->state.pns = PNS_WAIT_DISCONNECT; @@ -427,7 +430,7 @@ void pptp_conn_close(PPTP_CONN * conn, u for (i = 0; i < vector_size(conn->call); i++) pptp_call_close(conn, vector_get_Nth(conn->call, i)); /* now close connection */ - log("Closing PPTP connection"); + log("Closing PPTP connection (sending stop ctrl conn rqst)"); pptp_send_ctrl_packet(conn, &rqst, sizeof(rqst)); pptp_reset_timer(); /* wait 60 seconds for reply */ conn->conn_state = CONN_WAIT_STOP_REPLY; @@ -706,7 +709,17 @@ int ctrlp_disp(PPTP_CONN * conn, void * hton16(PPTP_MAX_CHANNELS), hton16(PPTP_FIRMWARE_VERSION), PPTP_HOSTNAME, PPTP_VENDOR }; int idx, rc; - log("Received Start Control Connection Request"); + log("Received Start Control Connection Request: v%d rcode %d ecode %d fcap %x bcap %x chans %d fw %x host `%.64s' vendor `%.64s'", + ntoh16(packet->version), + packet->result_code, + packet->error_code, + ntoh32(packet->framing_cap), + ntoh32(packet->bearer_cap), + ntoh16(packet->max_channels), + ntoh16(packet->firmware_rev), + packet->hostname, + packet->vendor + ); /* fix this packet, if necessary */ idx = get_quirk_index(); if (idx != -1 && pptp_fixups[idx].start_ctrl_conn) { @@ -719,9 +732,11 @@ int ctrlp_disp(PPTP_CONN * conn, void * reply.version = packet->version; /* protocol version not supported */ reply.result_code = hton8(5); + log("sending start ctrl conn reply (NAK)"); pptp_send_ctrl_packet(conn, &reply, sizeof(reply)); pptp_reset_timer(); /* give sender a chance for a retry */ } else { /* same or greater version */ + log("sending start ctrl conn reply (ACK)"); if (pptp_send_ctrl_packet(conn, &reply, sizeof(reply))) { conn->conn_state = CONN_ESTABLISHED; log("server connection ESTABLISHED."); @@ -735,7 +750,18 @@ int ctrlp_disp(PPTP_CONN * conn, void * { struct pptp_start_ctrl_conn *packet = (struct pptp_start_ctrl_conn *) buffer; - log("Received Start Control Connection Reply"); + log("Received Start Control Connection Reply: v%d rcode %d ecode %d fcap %x bcap %x chans %d fw %x host `%.64s' vendor `%.64s'", + ntoh16(packet->version), + packet->result_code, + packet->error_code, + ntoh32(packet->framing_cap), + ntoh32(packet->bearer_cap), + ntoh16(packet->max_channels), + ntoh16(packet->firmware_rev), + packet->hostname, + packet->vendor + ); + if (conn->conn_state == CONN_WAIT_CTL_REPLY) { /* XXX handle collision XXX [see rfc] */ if (ntoh16(packet->version) != PPTP_VERSION) { @@ -778,14 +804,21 @@ int ctrlp_disp(PPTP_CONN * conn, void * /* ----------- STANDARD Stop-Session MESSAGES ------------ */ case PPTP_STOP_CTRL_CONN_RQST: { + struct pptp_stop_ctrl_conn *packet = + (struct pptp_stop_ctrl_conn *) buffer; /* conn_state should be CONN_ESTABLISHED, but it could be * something else */ struct pptp_stop_ctrl_conn reply = { PPTP_HEADER_CTRL(PPTP_STOP_CTRL_CONN_RPLY), hton8(1), hton8(PPTP_GENERAL_ERROR_NONE), 0 }; - log("Received Stop Control Connection Request."); + log("Received Stop Control Connection Request: reason %d err %d reserved %d", + packet->reason_result, + packet->error_code, + ntoh16(packet->reserved1) + ); if (conn->conn_state == CONN_IDLE) break; + log("sending stop ctrl conn reply"); if (pptp_send_ctrl_packet(conn, &reply, sizeof(reply))) { if (conn->callback != NULL) conn->callback(conn, CONN_CLOSE_RQST); @@ -796,7 +829,13 @@ int ctrlp_disp(PPTP_CONN * conn, void * } case PPTP_STOP_CTRL_CONN_RPLY: { - log("Received Stop Control Connection Reply."); + struct pptp_stop_ctrl_conn *packet = + (struct pptp_stop_ctrl_conn *) buffer; + log("Received Stop Control Connection Reply: reason %d err %d reserved %d", + packet->reason_result, + packet->error_code, + ntoh16(packet->reserved1) + ); /* conn_state should be CONN_WAIT_STOP_REPLY, but it * could be something else */ if (conn->conn_state == CONN_IDLE) break; @@ -842,9 +881,23 @@ int ctrlp_disp(PPTP_CONN * conn, void * hton32(PPTP_CONNECT_SPEED), hton16(PPTP_WINDOW), hton16(PPTP_DELAY), 0 }; - log("Received Outgoing Call Request."); + log("Received Outgoing Call Request: id %x csn %d minbps %d max %d bearer %x framing %x rsize %d delay %d plen %d rsv1 %d phone `%.64s' sub `%.64s'", + ntoh16(packet->call_id), + ntoh16(packet->call_sernum), + ntoh32(packet->bps_min), + ntoh32(packet->bps_max), + ntoh32(packet->bearer), + ntoh32(packet->framing), + ntoh16(packet->recv_size), + ntoh16(packet->delay), + ntoh16(packet->phone_len), + ntoh16(packet->reserved1), + packet->phone_num, + packet->subaddress + ); /* XXX PAC: eventually this should make an outgoing call. XXX */ reply.result_code = hton8(7); /* outgoing calls verboten */ + log("sending out call reply (NAK)"); pptp_send_ctrl_packet(conn, &reply, sizeof(reply)); break; } @@ -854,7 +907,17 @@ int ctrlp_disp(PPTP_CONN * conn, void * (struct pptp_out_call_rply *)buffer; PPTP_CALL * call; u_int16_t callid = ntoh16(packet->call_id_peer); - log("Received Outgoing Call Reply."); + log("Received Outgoing Call Reply: id %x peer %d result %d err %d cause %x speed %d rsize %d delay %d channel %x", + ntoh16(packet->call_id), + ntoh16(packet->call_id_peer), + packet->result_code, + packet->error_code, + ntoh16(packet->cause_code), + ntoh32(packet->speed), + ntoh16(packet->recv_size), + ntoh16(packet->delay), + ntoh32(packet->channel) + ); if (!vector_search(conn->call, (int) callid, &call)) { log("PPTP_OUT_CALL_RPLY received for non-existant call: " "peer call ID (us) %d call ID (them) %d.", @@ -908,12 +971,16 @@ int ctrlp_disp(PPTP_CONN * conn, void * PPTP_HEADER_CTRL(PPTP_CALL_CLEAR_NTFY), packet->call_id, 1, PPTP_GENERAL_ERROR_NONE, 0, 0, {0} }; - log("Received Call Clear Request."); + log("Received Call Clear Request: cid %d reserved %d", + ntoh16(packet->call_id), + ntoh16(packet->reserved1) + ); if (vector_contains(conn->call, ntoh16(packet->call_id))) { PPTP_CALL * call; vector_search(conn->call, ntoh16(packet->call_id), &call); if (call->callback != NULL) call->callback(conn, call, CALL_CLOSE_RQST); + log("sending call clear ntfy"); pptp_send_ctrl_packet(conn, &reply, sizeof(reply)); pptp_call_destroy(conn, call); log("Call closed (RQST) (call id %d)", (int) call->call_id); @@ -924,8 +991,13 @@ int ctrlp_disp(PPTP_CONN * conn, void * { struct pptp_call_clear_ntfy *packet = (struct pptp_call_clear_ntfy *)buffer; - log("Call disconnect notification received (call id %d)", - ntoh16(packet->call_id)); + log("received call clear ntfy: cid %d result %d err %d cause %x reserved %d", + ntoh16(packet->call_id), + packet->result_code, + packet->error_code, + ntoh16(packet->cause_code), + ntoh16(packet->reserved1) + ); if (vector_contains(conn->call, ntoh16(packet->call_id))) { PPTP_CALL * call; ctrlp_error(packet->result_code, packet->error_code, @@ -944,12 +1016,12 @@ int ctrlp_disp(PPTP_CONN * conn, void * /* this is really dealt with in the HDLC deencapsulation, anyway. */ struct pptp_set_link_info *packet = (struct pptp_set_link_info *)buffer; - /* log it. */ - log("PPTP_SET_LINK_INFO received from peer_callid %u", - (unsigned int) ntoh16(packet->call_id_peer)); - log(" send_accm is %08lX, recv_accm is %08lX", - (unsigned long) ntoh32(packet->send_accm), - (unsigned long) ntoh32(packet->recv_accm)); + log("received set link info: peer %x res %d send %x recv %x\n", + ntoh16(packet->call_id_peer), + ntoh16(packet->reserved1), + ntoh32(packet->send_accm), + ntoh32(packet->recv_accm) + ); if (!(ntoh32(packet->send_accm) == 0 && ntoh32(packet->recv_accm) == 0)) warn("Non-zero Async Control Character Maps are not supported!"); @@ -1051,6 +1123,7 @@ static void pptp_handle_timer() } else { /* ka_state == NONE */ /* send keep-alive */ struct pptp_echo_rqst rqst = { PPTP_HEADER_CTRL(PPTP_ECHO_RQST), hton32(global.conn->ka_id) }; + log("sending echo request: %d", global.conn->ka_id); pptp_send_ctrl_packet(global.conn, &rqst, sizeof(rqst)); global.conn->ka_state = KA_OUTSTANDING; }